Record check timings only when -XepPrintTimings asks for them - #6080
Open
vlsi wants to merge 1 commit into
Open
Conversation
ErrorProneScanner opens a timing span for every matcher on every AST node, and nothing reads what the spans record: ErrorProneTimings.timings() and initializationTime() have no callers in check_api or core, and no test asserts on either. Compiling error_prone_core opens 14771508 spans, and Calcite's :core opens 28493608; measured against a build whose spans are no-ops, they cost a median of 656 ms of a 13.0 s compile and 1216 ms of a 37 s one. The spans are now gated on -XepPrintTimings, which also prints the per-check totals once the compilation finishes, so a build that does not ask for the data does not collect it and a build that does can read it. Issue google#6079 has the measurements and proposes making the collection itself cheap enough to leave on; that is a larger change and is not this one. Assisted-by: Claude Code (claude-opus-5)
vlsi
added a commit
to vlsi/error-prone
that referenced
this pull request
Aug 31, 2026
Timing a check on every invocation costs about as much as the cheapest invocations it measures: on error_prone_core 45% of spans are shorter than 128 ns and carry 2.9% of the recorded time, while a pair of System.nanoTime calls measures 24 ns to 27 ns. So the count is now exact and the elapsed time is sampled, and a sample counts for the invocations it stands in for. A check keeps its own CheckTiming, so the scanner reaches it without looking the check up by name, and a check whose mean invocation stays above a microsecond is timed on every one of them -- those are the checks a report is read for, and timing them perturbs each by a few percent at most. Measured against a build that opens no span at all, this costs a median of 209 ms of a 13.0 s compile where the Stopwatch it replaces costs 656 ms, and on Calcite's :core it is not distinguishable from having no spans, allocation included. The report gains the invocation count and the longest single invocation, which separate a check that is slow from one that paid a one-off cost: on Calcite InjectOnBugCheckers reads 7 ms over 21416 calls, and one run charged it 307 ms because the first constructor it saw triggered a type lookup the classpath could not answer. Estimates are worth what they can be checked against: CheckTimingTest drives the schedule and the weighted total through a supplied elapsed time rather than a clock, and ErrorProneTimingsTest covers both ways span reaches a check's state. See google#6079. This sits on top of the flag in google#6080 and is not proposed for merge until the shape of the collection is settled. Assisted-by: Claude Code (claude-opus-5)
This was referenced Aug 31, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Why
ErrorProneScanner.processMatchersopens a timing span for every matcher it runs on every AST node, and nothing reads what the spans record:ErrorProneTimings.timings()andinitializationTime()have no callers inerror_prone_check_apiorerror_prone_core, and no test asserts on either.The spans are not cheap at that frequency. Compiling
error_prone_coreitself opens 14771508 of them, and Calcite's:coreopens 28493608, each aHashMaplookup, twoSystem.nanoTimecalls, and a closure. Against a build whosespanreturns a shared no-op, alternating the two inside one JVM so each pair meets the same machine state, they cost a median of 656 ms of a 13.0 s compile and 1216 ms of a 37 s one, and on Calcite 0.42 GiB of allocation.#6079 has the full measurements.
What
-XepPrintTimingsgates the spans, so a compilation that does not pass it opens none. The same flag prints the per-check totals when the compilation finishes, so the data reaches whoever paid for it:Every check that ran gets a row, so the count in the header is the number of rows below it.
An embedder that reads
timings()programmatically now needs the flag too. That is the part worth arguing with, and #6079 says why I think the default belongs this way round: the collection has no consumer in this repository, and the flag is what gives it one.Making the collection itself cheap enough to leave on is a larger change, and #6079 proposes it separately.
How to verify
mvn -pl check_api,core test -Dtest=ErrorProneOptionsTest,ErrorProneJavaCompilerTestrecognizesPrintTimingsandprintTimingsIsOffByDefaultcover the option.printTimingsReportsEveryCheckThatRancompiles a real file and asserts both a non-zero count in the header and at least one row: the header alone is printed before the rows, so a build that collected nothing would still print one.withoutPrintTimingsNoReportIsPrintedcovers the default.Each test was watched failing: deleting the option's parse case fails the first, inverting the gate in
VisitorState.timingSpanfails the third on both of its assertions, and dropping theKind.COMPILATIONbranch fails it on the absent header.One limitation the tests do not cover: under Gradle the report does not reach the build log, because Gradle passes no writer to
JavaCompiler.getTaskand javac'sNOTICEwriter then goes to the compiler daemon's stderr. It arrives through any caller that supplies a writer. Emitting it as a diagnostic instead would fix that, and the same applies to whatRefactoringCollectionalready prints; I left both alone here.